000 О сбоях
- Иллюстрация сбоев и работы SRE
- Иметь материал для иллюстраций и ссылок последующих лекциях
Видео лекции устаревают и их содержание может не совпадать с текстом.
Масштабный сбой в мобильном банке на Android
11 декабря 2020 в мобильном приложении на Android перестал работать главный экран приложения. Не отображались счета и продукты. Пострадали кредитные и депозитные продукты, инвестиции, MNVO, SME, страхование и путешествия.
Снимок экрана
Как выглядело приложение во время сбоя 11 декабря 2020Что произошло
В мобильном банке на Android сломался главный экран приложения: не отображались счета и продукты. Это случилось после ошибочного редактирования конфигурации. Приложение не могло обработать ответ от сервера и выдавало пустой экран.
Пострадало около 300 тысяч пользователей, которые заходили в мобильный банк с Android-устройств первый раз за день в период с 16:13 до 17:15. Почти все продукты Тинькофф через мобильный банк были недоступны.
Сбой был настолько масштабным, что мы получили запрос из Банка России, о нас написали РБК, ТАСС и Коммерсант.
Пока о нас писали в СМИ, мы искали причины сбоя. Поиск ощутимо осложнился тем, что одновременно с пустым списком счетов из-за возросшей нагрузки «упали» мобильные истории. Поэтому именно они стали главными подозреваемыми в поиске виновника и первой версией, которую мы начали обрабатывать. Стоит упомянуть, что проблемы с мобильными историями к моменту сбоя проявлялись уже несколько недель, и мы о них знали, однако своевременно не устранили (техдолг).
Дневник
| Время | Действие |
|---|---|
| 16:48 | Начали тред после обнаружения сбоя |
| 16:49 | Организовали встречу в Зуме для обсуждения устранения сбоя. Всего во встрече поучаствовали 66 специалистов разных уровней |
| 16:50 | Собрали в чате кросс-платформенную группу для ликвидации сбоя |
| 16:54 | Выдвинули и проработали первую версию сбоя |
| 17:10 | Выдвинули вторую версию и начали работу над ней |
| 17:14 | Исправили конфигурацию |
| 17:20 | Попробовали исправить последствия сбоя на устройствах участников встречи в Зуме |
| 17:30 | Передали в колл-центр инструкцию для клиентов. Начали работу над ошибкой, возникающей при переходе на экран создания нового продукта |
| 17:40 | Починили ошибку на экране создания нового продукта |
| 18:17 | Починили истории |
| 18:20 | На главном экране ничего не изменилось |
| 18:25 | Получили дополнительную информацию по кэшу |
| 18:30 | Решили показать истории всем пострадавшим |
| 18:40 | Начали готовить истории, работать над механикой таргетирования |
| 19:10 | Решили добавить пуш-уведомления |
| 20:35 | Подготовили и отправили пуш-уведомления на часть пользователей |
| 21:37 | Подготовили вторую выборку клиентов |
| 22:12 | Отправили историю и пуши второй выборке клиентов |
| 22:50 | Получили сообщение о количестве просмотревших истории |
Поиск проблемы и причины
Каждую пятницу в течение последних нескольких недель нагрузка на истории увеличивалась, но точную причину установить не удавалось. Когда во время сбоя под возросшей трехкратной нагрузкой упали мобильные истории, мы сразу решили, что все произошло из-за них.
Команда мобильных историй начала экстренный анализ повышенной нагрузки на свое API. Главным подозреваемым выбрали ddos: казалось, это он так влияет на экран счетов. Поэтому исследовали параллельно два варианта: мобильные истории с обработкой и конфигурации мобильного приложения с обработкой.
Починка историй была важной задачей еще и потому, что после ликвидации сбоя именно они помогли нам сообщить пользователям о проблеме и дать инструкцию по восстановлению работы приложения.
Второй гипотезой, которую решили рассмотреть, стала конфигурация мобильного приложения, а именно файл, задающий список продуктов. И эта версия оказалась верной.
16:13 мск
Добавили невалидный элемент массива
16:13 мск
Добавили атрибут productПричины, которые привели к сбою:
- Отсутствовала защита от некорректного использования конфигураций в МБ: управление конфигурационными данными происходило без валидации при сохранении конфигурации и без проверки соответствия схеме. Мы просто редактировали и хранили JSON’ки.
- Обработка конфигурационных файлов на стороне клиентского приложения под Android без нормальной валидации. Достаточно сравнить работу приложений на iOS и Android: в первом случае все сработало штатно, во втором — список счетов развалился.
Триггером стала ошибка сотрудника при редактировании и сохранении ресурса products_info_v3, где хранится описание продуктов Тинькофф, с невалидным псевдопродуктом «Работа в Тинькофф». В описании продукта не заполнили часть обязательных полей, из-за этого мобильный банк не мог прочитать текст ответа от сервера и не отображал продукты. Во время устранения сбоя этот момент доработали, и теперь не показывается только сломанный элемент.
Также в самом процессе выкладки изменений в конфигурации существовали недоработки, которые подталкивали сотрудников к неправильным действиям:
- Изменения выкатили сразу на production.
- Пропустили этап обновления конфигурационного файла на стейдже.
- Не протестировали список продуктов в мобильном приложении.
Восстановление
Восстановление работы приложения проводили в несколько этапов. Сначала исправили конфигурацию ресурса products_info_v3 удалением элемента из массива, это решило проблему на стороне сервера. Но на стороне клиентов ничего не изменилось. После удаления элемента конфигурационные данные стали верными, но остался вопрос кэширования.
Проверили очистку кэша и данных — продукты появились на главном экране, а значит, конфигурационные данные теперь верны.
Затем передали инструкцию по восстановлению работы в саппорт: сбросить кэш или переустановить приложение либо дождаться, когда приложение восстановится само. Мы предполагали, что кэшированные данные на устройствах пользователей хранятся один час, поэтому специалистам поддержки сообщили, что к 18:20 приложение заработает.
Когда все починили, провели анализ точного времени начала сбоя, чтобы понять, сколько человек пострадали. Параллельно восстанавливали работу мобильных историй, которые все еще не работали из-за нагрузки, и реализовали ограничение на возможность редактирования конфигурации мобильного приложения.
После того, как мы проставили лимиты на API, бэкенд историй перестало заливать запросами. Функциональность восстановилась, и клиенты снова могли их смотреть. Мы планировали использовать истории как транспорт для доставки сообщений по устранению проблемы с отображением продуктов.
В час Х, когда кэш должен был сброситься автоматически, мы ждали, что у пользователей на главном экране появятся продукты, но этого не произошло. Мы получили информацию, что кэш живет не один час, как считали изначально, а целый день. После этого ошеломительного известия стало ясно, что ждать целые сутки — слишком долго. Необходимо как-то оповестить пользователей и предложить им пути решения.
Тут стоит отметить проблему коммуникации между сотрудниками, а именно отсутствие общедоступной документации по времени жизни кэша.
Информирование пользователей
Оптимальным мы сочли информирование пользователей через сторис: показать и объяснить, как устранить неполадки на их устройствах.
На созвоне покреативили, придумали оформление и содержание. Параллельно работали с механикой таргетирования, чтобы сторис попала ко всем пострадавшим.
Учитывая, что сторис увидят только те, кто зайдут в мобильный банк, а остальные ничего не узнают, мы добавили к процессу пуш-уведомления.
Из-за отсутствия регламента по коммуникациям с клиентами во время крупных сбоев, на создание контента, согласование текста и формирование выборки для таргетинга ушло почти два часа. В будущем необходимо заготовить макеты историй и пушей, чтобы оперативно, а главное своевременно оповещать пострадавших пользователей.
Истории и нотификации пришли не всем сотрудникам, которые участвовали в устранении сбоя. Стало понятно, что первоначальная выборка была не полной. Чтобы уведомить оставшихся, мы подготовили вторую выборку. После второй рассылки пришло уведомление, что истории посмотрели свыше 50 тысяч клиентов. Это означало, что информация дошла до клиентов и помогла им восстановить работу приложения.
Чему мы научились
Из этого сбоя мы извлекли ряд уроков и внесли изменения в существующие алгоритмы работы:
- Отсутствовала защита от некорректного использования конфигураций в МБ:
- Отработали подход работы с конфигурациями и сделали его контролируемым;
- Отняли права на редактирование конфигов у всех, кроме доверенных специалистов..
- В приложении на Android не было валидации конфигураций:
- Добавили валидацию входных данных, как у iOS;
- Внедрили ревью конфигураций при сохранении в мобильном приложении.
- Недоработки процесса выкладки изменений конфигураций:
- Добавили тестирование перед переносом изменений на production, чтобы исключить релизы с ошибками;
- Разрабатываем удобный интерфейс для редактирования настроек мобильного банка.
- Проблема коммуникации между сотрудниками, отсутствие документации:
- Завели документацию по времени жизни кэша для конфигураций:
- Время существования кэша сократили до 1 часа;
- Сейчас работаем над тем, чтобы можно было удаленно сбросить кэш.
- Отсутствие регламента действий сотрудников и инструкций, шаблонов для коммуникаций с клиентами во время массовых сбоев:
- Разработали процесс действий во время «Чёрных» (массовых) сбоев.
Постмортем о том, зачем программистам знать про алгоритмы и асимптотику
Иногда в команде Тинькофф случаются такие сбои, которые не видны клиентам, но ощутимо влияют на работу внутри компании.
Именно про такой случай ниже.
Сложные запросы в Elasticsearch можно создавать с помощью Painless Script. То есть запросы бывают без Painless-скриптов — JSON и с Painless-скриптами — JSON + Painless. Sage использует оба типа, стараясь использовать вариант без скриптов, если возможно.
Оказалось, что в случаях, когда в запросе используется длинный тернарный оператор, парсер скрипта работает за экспоненциальное время и скрипт на несколько десятков строк может парситься в течение нескольких часов. Баг репорт о этой проблеме на GitHub.
Для парсинга всех скриптов используется один поток, поэтому единственный скрипт может заблокировать все запросы с Painless на неопределенно долгое время. Заблокированные запросы с Painless в свою очередь блокируют воркеры, выполняющие любые запросы. И при регулярном поступлении «ломающих» запросов с Painless все воркеры окажутся заблокированными, после чего любая работа с поиском в Elasticsearch будет полностью парализована.
Именно это наблюдалось на Sage в течение двух дней.
Ситуация осложнялась багом в Mage: соединение не возвращалось в пул, если запрос завершился по таймауту, из-за чего у нас исчерпались пулы соединений в Mage.
Почему это произошло
К сбою привело множество причин. Все пользователи делают запросы в Elasticsearch не напрямую, а с помощью языка запросов Mage.
Пример Mage-запроса (1), который развернется в огромный запрос в Elasticsearch (2).
Обратите внимание на использование языка Painless в запросе.
group="platform_client" (level:"ERROR" OR level:"FATAL" OR level:"WARN") "TypeError" env="prod"
| where if("(pfp|pwa).*" != ".*", appName=="(pfp|pwa).*", appName:"pwa*" OR appName:"pfp*")
| timechart count as TypeError
{
"query": {
"bool": {
"must": [
{
"range": {
"@timestamp": {
"gte": "2020-09-25T03:28:19.269Z",
"lt": "2020-09-25T09:28:19.269Z"
}
}
},
{
"bool": {
"filter": [
{
"bool": {
"filter": [
{
"bool": {
"filter": [
{ "term": { "group": "platform_client" } },
{
"bool": {
"should": [
{
"span_near": {
"in_order": true,
"slop": 0,
"clauses": [
{ "span_term": { "level": "error" } }
]
}
},
{
"bool": {
"should": [
{
"span_near": {
"in_order": true,
"slop": 0,
"clauses": [
{
"span_term": { "level": "fatal" }
}
]
}
},
{
"span_near": {
"in_order": true,
"slop": 0,
"clauses": [
{ "span_term": { "level": "warn" } }
]
}
}
]
}
}
]
}
}
]
}
},
{
"span_near": {
"in_order": true,
"slop": 0,
"clauses": [{ "span_term": { "all": "typeerror" } }]
}
}
]
}
},
{
"script": {
"script": {
"lang": "painless",
"source": "boolean fulltextSearch(String s, String p) {\n s = s.toString().toLowerCase();\n p = p.toString().toLowerCase();\n if (!p.contains('*')) {\n return s.contains(p);\n }\n int i = 0;\n int j = 0;\n int starIndex = -1;\n int iIndex = -1;\n while (i < s.length()) {\n if (j < p.length() && p.charAt(j) == s.charAt(i)) {\n ++i;\n ++j;\n } else if (j < p.length() && p.charAt(j) == (char)'*') {\n starIndex = j;\n iIndex = i;\n j++;\n } else if (starIndex != -1) {\n j = starIndex + 1;\n i = iIndex+1;\n iIndex++;\n } else {\n return false;\n }\n }\n while (j < p.length() && p.charAt(j) == (char)'*') {\n ++j;\n }\n return j == p.length();\n}def s11 = \"pfp*\";def s10 = (!doc.containsKey('appName.keyword') || doc['appName.keyword'].size() == 0 ? null : doc['appName.keyword'].value);def s12 = ((s10) != null && fulltextSearch(s10,s11));def s8 = \"pwa*\";def s7 = (!doc.containsKey('appName.keyword') || doc['appName.keyword'].size() == 0 ? null : doc['appName.keyword'].value);def s9 = ((s7) != null && fulltextSearch(s7,s8));def s13 = (s9 == null || s12 == null ? null : s9 || s12);def s5 = \"(pfp|pwa).*\";def s4 = (!doc.containsKey('appName.keyword') || doc['appName.keyword'].size() == 0 ? null : doc['appName.keyword'].value);def s6 = (s4 == s5);def s2 = \".*\";def s1 = \"(pfp|pwa).*\";def s3 = (s1 != s2);def result = (s3 === true ? s6 : s13); return result == null ? false : result"
}
}
}
]
}
}
]
}
},
"aggs": {
"buckets": {
"composite": {
"sources": [
{
"@timestamp": {
"date_histogram": {
"field": "@timestamp",
"fixed_interval": "300s"
}
}
}
],
"size": 2500
},
"aggs": {}
}
},
"_source": true,
"track_total_hits": true,
"size": 0
}
Предпосылкой сбоя стала новая функциональность Case для языка Mage, которую мы выложили 24 июля.
group="mp_smsc" logfile:"1-smsc*"
| eval kodik=case(Error_code="1-02", "Некорректный адрес отправителя", Error_code="1-03", "Адрес отправителя обнаружен в черном списке", Error_code="1-04", "Адрес получателя обнаружен в черном списке", Error_code="1-05", "Адрес отправителя не обнаружен в белом списке", Error_code="1-07", "Нельзя принимать от данного абонента", Error_code="1-08", "Нельзя отправлять на данного абонента", Error_code="1-09", "Нельзя принимать от данного абонента", Error_code="1-10", "Ошибка при обработке SMS встроенной службой", Error_code="1-11", "Ошибка от биллинга", Error_code="2-05", "Переполнение очереди абонента", Error_code="2-06", "Переполнение очереди", Error_code="4-20", "Сообщение «ALERT»", Error_code="5-21", "Изменение профиля «Заказ отчета о доставке фазы один»", Error_code="5-22", "Изменение профиля «Заказ транслитерации»", Error_code="5-23", "Изменение профиля «Сообщение - Автоответ»", Error_code="5-24", "Изменение профиля «Номер для переадресации»", Error_code="5-25", "Изменение профиля «Псевдоним»", Error_code="5-26", "Изменение профиля «Заказ детализированного отчета»", Error_code="5-27", "Изменение профиля «Инкогнито»", Error_code="6-40", "Групповое удаление сообщений в очереди", Error_code="6-41", "Групповое изменение параметров сообщений в очереди", Error_code="6-42", "Отображение сообщений в очереди", Error_code="8-01", "Попытка регистрации дубликата части конкатенированного сообщения")
| timechart span=10m count by kodik, inst
Запрос выше компилируется в длинный тернарный оператор в Painless-скрипте. Экспоненциальное время парсинга скрипта растет с увеличением ветвления. В составленном запросе более 20 веток, а запросы обрабатываются корректно, когда веток не более 5.
{
"query": {
"bool": {
"must": [
{
"range": {
"@timestamp": {
"gte": "2020-09-25T08:49:37.534Z",
"lt": "2020-09-25T08:54:37.534Z"
}
}
},
{
"bool": {
"filter": [
{ "term": { "group": "mp_smsc" } },
{
"span_near": {
"in_order": true,
"slop": 0,
"clauses": [
{
"span_multi": {
"match": { "prefix": { "logfile": "1-smsc" } }
}
}
]
}
}
]
}
}
]
}
},
"aggs": {
"buckets": {
"composite": {
"sources": [
{
"kodik": {
"terms": {
"script": {
"lang": "painless",
"source": "
// отформатировано для упрощения чтения
def s92 = “Попытка регистрации дубликата части конкатенированного сообщения“;
def s90 = “8-01“;
def s89 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s91 = (s89 == s90);
def s88 = “Отображение сообщений в очереди“;
def s86 = “6-42“;
def s85 =(
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s87 = (s85 == s86);
def s84 = “Групповое изменение параметров сообщений в очереди“;
def s82 = “6-41“;
def s81 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s83 = (s81 == s82);
def s80 = “Групповое удаление сообщений в очереди“;
def s78 = “6-40“;
def s77 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s79 = (s77 == s78);
def s76 = “Изменение профиля «Инкогнито»“;
def s74 = “5-27“;
def s73 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s75 = (s73 == s74);
def s72 = “Изменение профиля «Заказ детализированного отчета»“;
def s70 = “5-26“;
def s69 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s71 = (s69 == s70);
def s68 = “Изменение профиля «Псевдоним»“;
def s66 = “5-25“;
def s65 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s67 = (s65 == s66);
def s64 = “Изменение профиля «Номер для переадресации»“;
def s62 = “5-24“;
def s61 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s63 = (s61 == s62);
def s60 = “Изменение профиля «Сообщение - Автоответ»“;
def s58 = “5-23“;
def s57 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s59 = (s57 == s58);
def s56 = “Изменение профиля «Заказ транслитерации»“;
def s54 = “5-22“;
def s53 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s55 = (s53 == s54);
def s52 = “Изменение профиля «Заказ отчета о доставке фазы один»“;
def s50 = “5-21“;
def s49 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s51 = (s49 == s50);
def s48 = “Сообщение «ALERT»“;
def s46 = “4-20“;
def s45 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s47 = (s45 == s46);
def s44 = “Переполнение очереди“;
def s42 = “2-06“;
def s41 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s43 = (s41 == s42);
def s40 = “Переполнение очереди абонента“;
def s38 = “2-05“;
def s37 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s39 = (s37 == s38);
def s36 = “Ошибка от биллинга“;
def s34 = “1-11“;
def s33 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s35 = (s33 == s34);
def s32 = “Ошибка при обработке SMS встроенной службой“;
def s30 = “1-10“;
def s29 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s31 = (s29 == s30);
def s28 = “Нельзя принимать от данного абонента“;
def s26 = “1-09“;
def s25 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s27 = (s25 == s26);
def s24 = “Нельзя отправлять на данного абонента“;
def s22 = “1-08“;
def s21 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s23 = (s21 == s22);
def s20 = “Нельзя принимать от данного абонента“;
def s18 = “1-07“;
def s17 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s19 = (s17 == s18);
def s16 = “Адрес отправителя не обнаружен в белом списке“;
def s14 = “1-05“;
def s13 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s15 = (s13 == s14);
def s12 = “Адрес получателя обнаружен в черном списке“;
def s10 = “1-04“;
def s9 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s11 = (s9 == s10);
def s8 = “Адрес отправителя обнаружен в черном списке“;
def s6 = “1-03“;
def s5 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s7 = (s5 == s6);
def s4 = “Некорректный адрес отправителя“;
def s2 = “1-02“;
def s1 = (
!doc.containsKey(‘Error_code.keyword’) || doc[‘Error_code.keyword’].size() == 0 ?
null : doc[‘Error_code.keyword’].value
);
def s3 = (s1 == s2);
return (
s3 === true ? s4 :
s7 === true ? s8 :
s11 === true ? s12 :
s15 === true ? s16 :
s19 === true ? s20 :
s23 === true ? s24 :
s27 === true ? s28 :
s31 === true ? s32 :
s35 === true ? s36 :
s39 === true ? s40 :
s43 === true ? s44 :
s47 === true ? s48 :
s51 === true ? s52 :
s55 === true ? s56 :
s59 === true ? s60 :
s63 === true ? s64 :
s67 === true ? s68 :
s71 === true ? s72 :
s75 === true ? s76 :
s79 === true ? s80 :
s83 === true ? s84 :
s87 === true ? s88 :
s91 === true ? s92 :
null
);
"
}
}
}
},
{
"@timestamp": {
"date_histogram": {
"field": "@timestamp",
"fixed_interval": "300s"
}
}
}
],
"size": 2500
},
"aggs": {}
}
},
"_source": true,
"track_total_hits": true,
"size": 0
}
23 сентября в 14:36 мск запрос послали в Mage и получили блокировку компиляции всех Painless-скриптов. Сначала заблокировались воркеры и начала копиться очередь запросов к Elasticsearch на заблокированных целиком нодах. Снять очередь можно только перезагрузкой Elasticsearch-нод. Это провоцирует баг в Mage, потому что из-за рестарта не возвращаются в пул соединения с Elastic, если запрос завершается таймаутом (более 90 секунд).
Восстановление
Баг в Mage пофиксили почти сразу после начала сбоя. Возврат соединения в пул после таймаута починили.
Запросы, которые могут убить Elasticsearch, ограничены лимитом в Mage. Однако возможность сформировать такой запрос все еще осталась.
Чтобы полностью предотвратить подобные сбои в будущем, необходимо обновить Elasticsearch. Но это не значит, что в ES не осталось других подобных «бомб».
Для реанимации ES во время сбоя нужно было с помощью мониторинга отыскать, на каких нодах есть зависшие запросы, и перезапустить их. Критерии поиска: Thread Pools с типом search не нулевой и никогда не уменьшается.
После чего идет долгий процесс переинициализации ES и возвращение шардов в работу. А затем долго откачиваются все накопившиеся в очереди в Kafka сообщения. При этом восстановление пройдет быстрее, если полностью остановить индексацию, иначе оно займет много дней.
Дневник 23.09.2020
| Время | Действие |
|---|---|
| 16:00 | Попробовали перезапустить Mage. Поменяли различные настройки в Elasticsearch. Предполагали, что поиск не работает из Elastic, но стандартные методы реанимации не помогли |
| 16:35 | Выкатили Mage v0.24.2 с увеличенным в два раза пулом соединений, но пул забивался почти так же быстро |
| 16:50 | Отключили по одной компоненте: Grafana-Proxy и Sauron API + Sauron Scheduler. Отключение не помогло |
| 17:00 | Включили обратно Grafana-Proxy и Sauron API + Sauron Scheduler. Начали опрос пользователей, которые запускают самые сложные запросы, запускали ли они такие после 15 часов |
| 17:45 | Отключили алертинг на кластере soc — остался только поиск через UI.sage. Пользователи почти никогда его не используют, и мы решили, что это удачная площадка для проверки гипотез. Поиск Mage заработал, но через некоторое время опять началась деградация |
| 17:50 | Попросили отключить интеграцию Anodot, который генерирует постоянные запросы и отправляет во внешний сервис мониторинга. Помогло, и дежурный посчитал, что причина была в этом |
| 18:10 | Попросили включить интеграцию Anodot обратно — для подтверждения гипотезы. Ждали, упадет ли поиск |
| 18:14 | Попросили снова выключить интеграцию Anodot. Мы думали, что после этого перезапуск Mage и поиск снова заработает |
| 18:20 | Версия с Anodot не подтвердилась |
| 19:20 | Выпустили релиз Mage v0.24.4 с отключенными ретраями и автодополнением, также основанным на поиске в Elastic. Снова не помогло, плюс сломался поиск по метрикам |
| 19:50 | Попробовали тот же фикс Mage v0.24.4 на кластере soc, предположили, что поиск ломают пользователи. Не помогло — вернули везде Mage v0.24.2 |
| 20:30 | Исходя из того, что причина где-то в Mage, потому что там лочатся соединения и не возвращаются в пул, мы решили: на ночь сделать скрипт с авторестартом Mage, чтобы алерты продолжали работать, и добавить метрик и логов в Mage для понимания ситуации. Часть новых метрик добавили сразу, быстрым релизом. Это подтвердило проблему залипания соединений в Mage. Заметили, что очереди копятся на ES, и рестартовали часть ES-нод. Показалось, что это помогло |
| 22:00 | Запустили авторестарт на Mage каждые 5 минут |
Дневник 24.09.2020
В 10:06 мск получили от коллеги запрос, который запускали после 15:00 и получали ошибку. Проанализировали запрос, решили, что вряд ли он мог стать причиной сбоя. Продолжили исследовать сбой.
Нашли утечку соединений в Mage после таймаута. Таймаутов было мало, и поэтому о ней никто не знал. Выпустили релиз, но проблема осталась, а мы продолжили «копать».
Обнаружили забитые пулы воркеров и тысячи запросов в очереди ES. Выдвинули гипотезу о бесконечных зависших или медленных запросах — while true запросах. Но чрезмерной нагрузки CPU или других аномалий не было, запросы просто столпились и ждали чего-то.
Сняли всю нагрузку с кластера Elasticsearch, постепенно остановили все процессы. Тогда начал копиться большой лаг, потому что остановились вычитка и процессинг логов. Загруженные пулы никак не реагировали на наши действия и оставались такими же забитыми.
Учитывая, что пулы чистятся только рестартом Elasticsearch, мы перезапустили 75% всех нод, на которых зависли запросы на поиск. Mage запустили только в режиме запросов по метрикам, чтобы работала хотя бы часть алертов.
Рестарт нод — тяжелая операция для ES: нужно много времени на перечитывание и проверку всех данных, прежде чем они станут доступными. Особенно warm-ноды, на которых много данных, и HDD диски. В ожидании восстановления попробовали тюнить параметры Elasticsearch, чтобы он восстанавливался быстрее.
Доработали логирование в Mage и приготовились «ловить» зависающие запросы. Создали алерты на подобную ситуацию. Через 10 часов Elasticsearch восстановился и выглядел работоспособным, но понимания, что именно сломалось, все еще нет.
Дневник 25.09.2020
В 12:05 мск во время дейлика сработал новый мониторинг и оповестил о забившихся воркерах. Снова.
Мы срочно остановили все запросы и начали ловить тот самый. Выявили много сложных запросов, один из них показался особенно подозрительным, и мы обвинили его. Получалось очень правдоподобно, так как такие же запросы, но с вырезанными Painless-скриптами отработали, а оригинальные повышали забитость воркеров сразу после отправки.
Мы попытались воспроизвести поведение на тестовом кластере и локально, но ничего не получилось. Поискали другие запросы и нашли наконец виновника. Дополнительно нашли тот же запрос в районе 14:00 от 23.09.
Воспроизвели поведение локально, но не на тесте, так как там другая версия Elastic, а обновиться не смогли из-за багов и несовместимости компонент.
Нашли соответствующий баг в Elasticsearch, который объяснил все, что мы наблюдали. Перезапустили и восстановили все кластеры, сделали релиз Mage, чтобы не допускать более 5 вариантов в Case, а Elasticsearch мог все распарсить за приемлемое время.
Лаг из сообщений откачивался почти двое суток, и на этом последствия сбоя были полностью устранены.
Чему мы научились
Нам повезло, что во время сбоя все руководители были на выездной встрече и мы не тратили время на объяснения, чтобы всех успокоить.
Но не повезло, что баг пофиксили в той версии, которая была на тестовом контуре. Именно поэтому наши тесты ничего не показывали на Mage. И не повезло, что сам баг был «сложносочиненным»: изначально в Elastic, который триггерил баг в Mage, поэтому мы путали причину и следствие.
Что сделали:
- Обновили версию Elasticsearch до 7.7.0 и выше.
- Все метрики Mage — по скриптам и без Painless стали считать отдельно и мониторить.
- Тестируем в той же версии Elastic, что и в продакшене.
- Пишем генерируемые стресс-тесты на язык Mage.
- Prober проверяет запросы с Painless и без Painless и сообщает о ходе проверок.
- Пересмотрели вопросы информирования во время сбоя. Написали простую и понятную единую инструкцию.
Постмортем о том, как на ноде Hazelcast filebeat загрузил CPU на 100%
17 февраля 2021 года в приложениях банка произошел сбой. Клиенты не могли войти в личный кабинет, воспользоваться Инвестициями, частично отказали Страхование и Мобайл.
Что сломалось
17 февраля в 15:08 по Москве на одной из нод портального Hazelcast filebeat загрузил CPU на 100%, что привело к сбою в работе внутренних и клиентских серверов. Кластеру не хватило ресурсов, чтобы обслуживать запросы от API. Hazelcast стал медленно отвечать, а из-за долгой обработки запросов закончились файловые дескрипторы. Появились ошибки при входе в мобильное приложение и личный кабинет. Не загружались счета, не работали платежи и переводы. В мобильном приложении перестало работать Страхование: не получалось рассчитать, оформить, продлить и оплатить полисы Е-ОСАГО.
Трудности возникли с авторизацией в Инвестициях, клиенты не могли просматривать информацию о ценных бумагах, покупать или выставлять лимитные заявки, не видели свои счета.
Звонки перестали переводиться на голосового помощника, не работала услуга «Отвечает Олег», и клиенты не могли записать телефонный разговор. Появился лаг, из-за которого не получалось оперативно обрабатывать заявки на подключение к Тинькофф Мобайлу. Новым абонентам приходилось долго ждать, пока им подключат связь.
Такой масштабный сбой привел к тому, что к нам поступил запрос из центра мониторинга и реагирования на компьютерные атаки — ФинЦЕРТа, появилось много негативных отзывов о работе приложения, из-за которых в AppStore и Google Play желтое приложение банка просело в рейтинге.
Hazelcast — In-memory data grid, в котором мы храним session id и другую информация о пользователях.
Filebeat — доставщик лог-сообщений из hazelcat в Sage (и Splunk).
Prime — мастер-система по всем карточным счетам.
Интрасайт — портал, на котором содержится необходимая информация для консультации клиентов.
| Время | Действие |
|---|---|
| 15:08 | Получили сообщение о недоступности JMXExporter на нодах Hazelcast |
| 15:19 | Получили алерты о 5xx ошибках от сервисов API |
| 15:20 | Коллеги сообщили о проблемах на сети в дата центре DS. На дашбордах наблюдали спад переводов и платежей, при этом ошибок не было |
| 15:22 | Заметили, что увеличился трафик на id.tinkoff.ru, отвечающий за идентификацию клиентов, от нод, которые никак не взаимодействуют с API Тинькофф. Поведение сети было крайне странным |
| 15:25 | Выросла нагрузка на базе SSO |
| 15:26 | Существенно возросла нагрузка на базу данных Prime ISS из-за запросов к представлениям TCS_IB_ACCOUNTS и TCS_IB_CARD от серверов API |
| 16:35 | На PrimeV балансере пошли ошибки 502 (таймауты) |
Восстановление
В течение 10 минут после получения первого алерта открыли сбой максимальной критичности в SD и оповестили коллег через чат в Slack.
Через 15 минут от начала сбоя через Интрасайт оповестили сотрудников операционных отделов о влиянии, которое сбой оказывает на клиентов. Информацию на Интрасайте регулярно обновляли по мере того, как к нам поступали новые данные о сбое.
Были сложности с уведомлением коллег, потому что алертов поступило более двух тысяч. В таком объеме довольно сложно было выбирать только нужные и актуальные. Сообщать актуальные статусы по устранению сбоя требовалось в разные чаты и системы, что отнимало довольно много ценного времени.
Невозможно было определить точечное влияние в одном месте. Информацию о последствиях сбоя собирали по крупицам из обратной связи от сотрудников, обращений клиентов и от каждого направления поддержки во многих каналах.
| Время | Действие |
|---|---|
| 15:33 | Перезапустили filebeat на нодах Hazelcast |
| 17:20 | Выяснили, что за 10 минут до начала сбоя из ЕХТ-зоны удалили некоторые хосты, связанные с API. Предположили, что неполадки из-за них |
| 17:32 | Вернули хосты на старые значения — без результата. Продолжили исследовать сбой |
| 18:40 | Отключили истории в мобильном приложении, так как они генерируют большую нагрузку на API, когда проверяют, авторизован ли пользователь |
| 18:46 | Перезапустили Hazelcast. После этого влияние снизилось, но фон ошибок сохранился. Отключили filebeat на нодах Hazelcast, увеличили CPU на Hazelcast в 4 раза, добавили 70 нод API |
| 18:50 | Окончательно помог совместный рестарт Hazelcast и нод API |
Работа с клиентами
Чтобы понять масштаб и помочь пользователям в восстановлении доступа, нам нужен был список пострадавших. За основу выборки мы взяли клиентов, которые в период с 15:09 до 00:20 пробовали зайти в личный кабинет или мобильное приложение. На выходе получился реестр из 2,2 млн пользователей. Это клиенты, которые с большой долей вероятности испытывали сложности при взаимодействии с сервисами Тинькофф.
Вход в личный кабинет и мобильное приложение
Вечером в день сбоя, между 22:00—23:00 мск, мы отобрали пользователей, у которых было максимальное количество неудачных попыток входа.
174 тысячи наших пользователей получили СМС с извинениями. Разослать большее количество сообщений не получилось из-за долгого обсуждения критериев пострадавших, низкой скорости отправки СМС и приближения timezone: клиентам нельзя ночью отправлять сообщения.
Утром следующего дня были готовы истории для мобильного приложения с извинениями. В 11:30 мск истории отправили всем пострадавшим. К 00:00 19 февраля истории посмотрели 858 тысяч человек. Процесс информирования пользователей вышел не слишком удачным, потому что не было шаблона историй для сбоев такого уровня. Долгое время все обдумывали и согласовывали, а после всех согласований и правок история оказалась не такой-то уж извинительной.
Параллельно с подготовкой историй мы решили выслать всем пострадавшим пуши со ссылкой на историю. Но оказалось, что 2 миллиона пушей — это дневная норма, превышать которую нельзя. Чтобы отправить такое количество сообщений, пришлось бы отключить на этот день все маркетинговые кампании Тинькофф. Решили сократить выборку пострадавших и исключили тех, кто пробовал авторизоваться не больше двух раз. Осталось примерно 900 тысяч клиентов.
Запустили рассылку пушей, но столкнулись с новыми сложностями: максимальная скорость отправки — 10 тысяч в минуту с учетом параллельных рассылок. Учитывая ограничения, стали высылать по 5 тысяч пушей в минуту. Из-за затянувшегося согласования и утверждения технических вопросов рассылку начали в 15:00 мск, у восточных регионов началась timezone.
В 17:00 мск прошла встреча с топ-менеджерами компании, решили отключить рассылку. Был риск, что пуши создадут дополнительную нагрузку на колл-центр, который и так был перегружен. Некоторые клиенты ожидали ответа в очереди больше часа. Тем более что с момента сбоя прошел почти день и многие уже забыли о неприятных последствиях или вовсе их не заметили. Не хотелось напоминать, поэтому в итоге пуши получили только 200 тысяч клиентов.
Локальные неполадки с продуктами Тинькофф
453 клиента во время сбоя не смогли активировать карту. 19 февраля по списку отфильтровали тех, у кого получилось. Оставшихся 169 клиентов обзвонили и помогли им активировать карты.
3994 клиента во время сбоя не смогли получить ПИН-код к карте. Сначала мы хотели отправить пуши с инструкцией по получению ПИН-кода, но не смогли. Ошиблись в первичной выгрузке и выделили 4507 пользователей с такой проблемой. Затем обнаружили, что в логах нет информации, для какой карты пользователь хотел получить ПИН, а значит, нельзя найти тех, кто к моменту выборки ПИН все же получил.
290 тысяч клиентов не могли попасть в мобильное приложение по ПИН-коду. 98% пострадавших в течение следующего дня восстановили доступ самостоятельно. Для оставшихся команда мобильного приложения попыталась удаленно восстановить вход по ПИНу, что технически оказалось невозможным. Сотрудники бэк-офиса обзвонили 300 клиентов из выборки, половина пользователей оказалась старше 50 лет. Им помогли войти в приложение, во всех случаях помогал повторный вход или перерегистрация. Оставшимся клиентам отправили СМС-инструкцию по входу в мобильное приложение.
Сбой в Инвестициях
440 тысяч клиентов безуспешно пытались войти в мобильное приложение Инвестиций во время сбоя. Всем выслали извинения по e-mail, 18 февраля объявили днем без комиссий и дали публичный комментарий по сбою.
Сложности с поддержкой клиентов
Из-за сбоя очередь на звонках выросла до 30—60 минут, а в чатах — до 1,5 часов. В день сбоя включили системное оповещение для пользователей. Сообщали, что очередь на обслуживание большая, компания в курсе проблемы и работает над исправлением ситуации.
Около 65 тысяч клиентов попали в очередь и не дождались ответа. Мы хотели извиниться перед ними, но не получилось, потому что очередь в колл-центр сохранялась несколько дней после сбоя.
Чему мы научились
В работе внутри компании
- Разработали Crisis management plan, где описали, какие роли должны быть назначены и кем. Кто, что и когда делает, кто всех координирует, как работать с клиентами и другие важные нюансы критической ситуации.
- Проверить и ограничить (по CPU, оперативке и так далее) фоновые процессы на нодах API, Hazelcast, Cassandra (filebeat, Consul, JMX_exporter).
- Настроить GC на Hazelcast и Cassandra, чтобы предотвратить утечку оперативной памяти.
- Пересмотреть 30-секундный таймаут на чтение из Hazelcast.
- Перевести часть сервисов с балансера api.tinkoff.ru для диверсификации рисков. На момент сбоя на балансере находились сервисы, которые не зависят от API, например Инвестиции.
- Усилить мониторинг:
- Установить atop и async-profiler на ноды API:
- Добавить алерты и дашборды в Grafana на Hazelcast:
- isClusterSafe != 1.
- Количество нод в кластере.
- CPU > 80%.
- Память > 80%.
- Добавить алерты на чтение из fallback Cassandra.
- Добавить метрики на threadpool в API:
- Обычные threadpool.
- Шедулеры — обрабатывают активности и таймауты.
- Database пулы — то, что доступно через публичный интерфейс.
- Добавить метрики на запросы к Hazelcast:
- Количество отправленных команд.
- Количество команд, которые ожидают ответа в данный момент.
- Добавить метрики на файловые дескрипторы.
Cassandra — NoSQL база данных, в которой мы кешируем информация о пользователях.
Consul — сервис для управления конфигурациями приложений и распространения настроек.
В работе с клиентами
- Мы поняли, что обязательно нужен регламент для общения с клиентами во время крупных сбоев и после. Регламент должен описывать порядок действий и роли сотрудников.
- На случай сбоев должен быть список шаблонов СМС, пушей, историй, системных сообщений в чатах и звонках.
- Нужно создать механизм для быстрой отправки пушей и СМС всем пострадавшим.
- Проверить, есть ли логи по самым критическим для клиентов функциональностям и хватает ли там информации.
- Создать «карту здоровья», чтобы в реальном времени отслеживать работоспособность основных систем и критических процессов в компании.